Repeated publishCallBack errors in UAExpert log

[bremby]

Hi,

our server seems to work fine except that we're seeing a steady supply of these publishCallBack errors in UAExpert log: Error: UaSessionPrivate::publishCallBack - List of available sequence numbers is empty, at least current sequence number has to be available

It is also sometimes supplemented with a different error: Error: Publish failed [status=0x800a0000]

This is how we set up the server config:

    use opcua_server::config::ANONYMOUS_USER_TOKEN_ID;
    let OpcUaSettings { port, users } = opcua_settings;
    let pki_dir = OpcUaSettings::default_pki_folder()?;

    let (mut user_token_ids, user_tokens): (Vec<String>, Vec<ServerUserToken>) = users
        .into_iter()
        .map(|u| {
            let pwd = decrypt_or_nothing(u.password.clone(), inst_id.to_string()).unwrap();
            (u.user.clone(), ServerUserToken::user_pass(u.user, pwd))
        })
        .unzip();

    // If no users are defined, then allow anonymous access
    let mut b = opcua_server::builder::ServerBuilder::new()
        .application_name("app name")
        .application_uri(OPCUA_APPLICATION_URI)
        .host_and_port("0.0.0.0", port.0)
        .discovery_urls(vec!["/".into()])
        .pki_dir(pki_dir)
        .create_sample_keypair(true)
        .trust_client_certs();

    b = user_token_ids
        .iter()
        .zip(user_tokens.into_iter())
        .fold(b, |b, (user_token_id, user_token)| {
            b.user_token(user_token_id, user_token)
        });

    if user_token_ids.is_empty() {
        user_token_ids.push(ANONYMOUS_USER_TOKEN_ID.into());
    }

    b = b.endpoints(vec![
        ("none", ServerEndpoint::new_none("/", &user_token_ids[..])),
        (
            "basic256sha256_sign_encrypt",
            ServerEndpoint::new_basic256sha256_sign_encrypt("/", &user_token_ids[..]),
        ),
        (
            "basic256sha256_sign",
            ServerEndpoint::new_basic256sha256_sign("/", &user_token_ids[..]),
        ),
    ]);
    Ok(b.config())

... which is then used to create a server builder and then server. The server is populated with an independent hashmap that's loaded up through async threads. As far as we know, there should be no issue on our side.

Here's a log

INFO: edge-cli/src/bin/omnio/commands/launch.rs:264: Gateway successfully launched
WARN: <path>/server/src/config.rs:552: No product uri was set
WARN: <path>/server/src/config.rs:552: No product uri was set
INFO: <path>/crypto/src/certificate_store.rs:91: Creating sample application instance certificate and private key
INFO: edge-core/src/service.rs:288: Connecting to 192.168.10.77
INFO: edge-core/src/service.rs:296: Connected to 192.168.10.77
INFO: <path>/crypto/src/certificate_store.rs:534: Writing X509 cert to /root/.omnio/pki/own/cert.der
INFO: <path>/crypto/src/certificate_store.rs:182: Writing private key to /root/.omnio/pki/private/private.pem
INFO: <path>/server/src/server.rs:142: Server has chosen to auto trust client certificates. You do not want to do this in production code.
INFO: <path>/server/src/server.rs:451: OPC UA Server: Omnio Edge UA
INFO: <path>/server/src/server.rs:452: Base url: opc.tcp://0.0.0.0:4840
INFO: <path>/server/src/server.rs:453: Supported endpoints:
INFO: <path>/server/src/server.rs:457: Endpoint "basic256sha256_sign": /
INFO: <path>/server/src/server.rs:458: Security Mode: Sign
INFO: <path>/server/src/server.rs:459: Security Policy: Basic256Sha256
INFO: <path>/server/src/server.rs:460: Supported user tokens - ANONYMOUS
INFO: <path>/server/src/server.rs:457: Endpoint "basic256sha256_sign_encrypt": /
INFO: <path>/server/src/server.rs:458: Security Mode: SignAndEncrypt
INFO: <path>/server/src/server.rs:459: Security Policy: Basic256Sha256
INFO: <path>/server/src/server.rs:460: Supported user tokens - ANONYMOUS
INFO: <path>/server/src/server.rs:457: Endpoint "none": /
INFO: <path>/server/src/server.rs:458: Security Mode: None
INFO: <path>/server/src/server.rs:459: Security Policy: None
INFO: <path>/server/src/server.rs:460: Supported user tokens - ANONYMOUS
INFO: <path>/server/src/server.rs:306: Waiting for Connection
INFO: <path>/server/src/server.rs:331: Server has not set a discovery server url, so no registration will happen
INFO: <path>/server/src/server.rs:350: Handling new connection PollEvented { io: Some(TcpStream { addr: 127.0.0.1:4840, peer: 127.0.0.1:56398, fd: 15 }) }
INFO: <path>/server/src/comms/tcp_transport.rs:222: Socket info:
Linger - No linger,
TTL - 64
INFO: <path>/server/src/comms/tcp_transport.rs:270: Session started 2022-03-17 09:09:21.065549595 UTC
INFO: <path>/server/src/comms/secure_channel_service.rs:196: CloseSecureChannelRequest received, session closing
ERROR: <path>/server/src/comms/tcp_transport.rs:494: Server reader session status is BadConnectionClosed so finishing
INFO: <path>/server/src/comms/tcp_transport.rs:562: Read loop is finished
ERROR: <path>/server/src/comms/tcp_transport.rs:423: Write bytes task is in error
INFO: <path>/server/src/comms/tcp_transport.rs:66: subscriptions_task loop connection finished
INFO: <path>/server/src/comms/tcp_transport.rs:710: Subscription monitor is finished
INFO: <path>/server/src/comms/tcp_transport.rs:66: subscriptions_task loop connection finished
INFO: <path>/server/src/comms/tcp_transport.rs:749: Subscription receiver is finished
INFO: <path>/server/src/comms/tcp_transport.rs:335: Finished monitor task is finished
INFO: <path>/server/src/comms/tcp_transport.rs:634: Hello timeout is finished
INFO: <path>/server/src/server.rs:350: Handling new connection PollEvented { io: Some(TcpStream { addr: 127.0.0.1:4840, peer: 127.0.0.1:56400, fd: 15 }) }
INFO: <path>/server/src/comms/tcp_transport.rs:222: Socket info:
Linger - No linger,
TTL - 64
INFO: <path>/server/src/comms/tcp_transport.rs:270: Session started 2022-03-17 09:09:23.503615096 UTC
INFO: <path>/server/src/comms/tcp_transport.rs:634: Hello timeout is finished
ERROR: <path>/crypto/src/x509.rs:317: Cannot make certificate from null bytestring
INFO: <path>/server/src/events/audit/mod.rs:63: Audit Event: EventId=ByteString(ByteString { value: Some([154, 177, 208, 170, 6, 253, 71, 241, 128, 253, 171, 211, 194, 114, 122, 197]) }),EventType=i=2071,SourceNode=i=0,SourceName=[null],Time=2022-03-17T09:09:23.506716700+00:00,ReceiveTime=2022-03-17T09:09:23.506716700+00:00,Message=LocalizedText(LocalizedText { locale: UAString { value: None }, text: UAString { value: None } }),Severity=1,ActionTimeStamp=2022-03-17T09:09:23.506717300+00:00,Status=true,ServerId=[null],ClientAuditEntryId=[null],ClientUserId=[null],SessionId=ns=1;s=Session-1,SecureChannelId=1,ClientCertificate=ByteString(ByteString { value: None }),ClientCertificateThumbprint=[null],RevisedSessionTimeout=60000
INFO: <path>/server/src/events/audit/mod.rs:63: Audit Event: EventId=ByteString(ByteString { value: Some([23, 114, 29, 146, 72, 231, 70, 139, 151, 180, 231, 39, 153, 10, 143, 83]) }),EventType=i=2071,SourceNode=i=0,SourceName=[null],Time=2022-03-17T09:09:23.507177200+00:00,ReceiveTime=2022-03-17T09:09:23.507177200+00:00,Message=LocalizedText(LocalizedText { locale: UAString { value: None }, text: UAString { value: None } }),Severity=1,ActionTimeStamp=2022-03-17T09:09:23.507177800+00:00,Status=true,ServerId=[null],ClientAuditEntryId=[null],ClientUserId=[null],SessionId=ns=1;s=Session-1,ClientSoftwareCertificates=Array(Array { value_type: ExtensionObject, values: [], dimensions: [] }),UserIdentityToken=ExtensionObject(ExtensionObject { node_id: NodeId { namespace: 0, identifier: Numeric(318) }, body: ByteString(ByteString { value: Some([255, 255, 255, 255]) }) }),SecureChannelId=1
WARN: <path>/server/src/address_space/relative_path.rs:131: find_nodes_relative_path bad no match
WARN: <path>/server/src/address_space/relative_path.rs:131: find_nodes_relative_path bad no match
WARN: <path>/server/src/address_space/relative_path.rs:131: find_nodes_relative_path bad no match
WARN: <path>/server/src/address_space/relative_path.rs:131: find_nodes_relative_path bad no match
WARN: <path>/server/src/address_space/relative_path.rs:131: find_nodes_relative_path bad no match
ERROR: <path>/server/src/events/event_filter.rs:161: Invalid select clause node not found SimpleAttributeOperand { type_definition_id: NodeId { namespace: 0, identifier: Numeric(2041) }, browse_path: Some([QualifiedName { namespace_index: 0, name: UAString { value: Some("Changes") } }]), attribute_id: 13, index_range: UAString { value: None } }
ERROR: <path>/server/src/events/event_filter.rs:276: Where clause has invalid filter operand count

Any ideas welcome. :)

[laumann]

I wanted to follow up on this:

We currently use the server functionality and construct an address that is continually updated in its own thread. What we've discovered is that subscribing to one or more variables with UaExpert logging many "publishCallback - List of available sequence numbers is empty". Here's a screenshot of the situation:

[laumann]

I'm aware that the problem is not really well described here. We're working on trying to construct a reproducing example that we can share, but we wanted to open the issue just in case anyone reading would have any ideas.