Skip to content

Master read task failures other than periodic polls are logged without their cause #441

Description

@jadamcrain

Master task failures are only logged with their cause for periodic polls. The startup integrity scan, the automatic event scan, and single reads all discard the TaskError, so when one of them fails the user gets either a cause-free warning or nothing at all.

This makes malformed-response problems effectively undiagnosable unless the user has already enabled application-layer decoding, because the parse error text is otherwise rendered only inside the APP RX decode log.

Where it happens

ReadTask::on_task_error in dnp3/src/master/tasks/mod.rs binds err in all four arms and only interpolates it in one:

pub(crate) fn on_task_error(self, association: Option<&mut Association>, err: TaskError) {
    match self {
        ReadTask::StartupIntegrity(_) => { ... association.on_integrity_scan_failure(); }  // err unused
        ReadTask::PeriodicPoll(poll)  => { tracing::warn!("poll {} failed: {err}", poll.id); ... }
        ReadTask::EventScan(_)        => { ... association.on_event_scan_failure(); }      // err unused
        ReadTask::SingleRead(task)    => { task.on_task_error(err); }                      // not logged
    }
}

Association::on_integrity_scan_failure and on_event_scan_failure (dnp3/src/master/association.rs) emit bare tracing::warn!("startup integrity scan failed") / ("automatic event scan failed").

Association::notify_task_fail (dnp3/src/master/association.rs) forwards to AssociationInformation::task_fail and does not log at all, even though every task failure — read and non-read — flows through it.

The one place the underlying ObjectParseError is currently rendered is TransportReader::decode (dnp3/src/transport/reader.rs), which is gated on decode_level.application.enabled().

Reproduction

Point a master at an outstation that sends a group 111 octet string event with a ranged qualifier (0x00) instead of an index prefix. This is a real frame from a user report:

e4 81 00 00            FIR|FIN|CON, seq 4, Response, IIN=0
6f 05 00 00 00         g111v5, qualifier 0x00 (8-bit start/stop), start 0, stop 0
61 61 61 61 61         "aaaaa"
01 02 00 00 00 01      g1v2, qualifier 0x00, start 0, stop 0, flags = online

Ranged qualifiers are only valid for group 110; RangedVariation::parse_non_read returns InvalidQualifierForVariation for group 111. In MasterSession::process_read_response (dnp3/src/master/task.rs) the response.objects? propagates that error before confirm_solicited() is reached, so the master never sends the application-layer confirm, the outstation sits in confirm-wait until it times out, and the link is torn down and restarted.

With AppDecodeLevel::Nothing, that produces:

Startup integrity scan

WARN task{type=Function(Read) dest=1024}: startup integrity scan failed

Periodic poll, identical response

WARN task{type=Function(Read) dest=1024}: poll 0 failed: malformed response: Group111(5) may not be used with the qualifier: 1-byte start/stop (0x00)

The second line names the group, the variation, and the offending qualifier. The first says nothing usable.

Suggested fix

Log the TaskError in Association::notify_task_fail, independent of decode level. That is a single site covering all four read tasks plus non-read tasks, and it avoids duplicating the per-task warnings. TaskError::Shutdown and TaskError::Disabled should be excluded since they are normal lifecycle events. The existing poll {id} failed line should drop its {err} interpolation to avoid logging the cause twice.

Metadata

Metadata

Assignees

No one assigned

    Labels

    enhancementNew feature or request

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions